eviction: regression test + distinguish layer write from map insert #4005

problame · 2023-04-11T17:59:47Z

This patch adds a regression test for the threshold-based layer eviction.
The test asserts the basic invariant that, if left alone, the residence statuses will stabilize, with some layers resident and some layers evicted.
Thereby, we cover both the aspect of last-access-time-threshold-based eviction, and the "imitate access" hacks that we put in recently.

The aggressive period and threshold values revealed a subtle bug which is also fixed in this patch.
The symptom was that, without the Rust changes of this patch, there would be occasional test failures due to WARN... unexpectedly downloading log messages.
These log messages were caused by the "imitate access" calls of the eviction task.
But, the whole point of the "imitate access" hack was to prevent eviction of the layers that we access there.
After some digging, I found the root cause, which is the following race condition:

Compact: Write out an L1 layer from several L0 layers. This records residence event LayerCreate with the current timestamp.
Eviction: imitate access logical size calculation. This accesses the L0 layers because the L1 layer is not yet in the layer map.
Compact: Grab layer map lock, add the new L1 to layer map and remove the L0s, release layer map lock.
Eviction: observes the new L1 layer whose only activity timestamp is the LayerCreate event.

The L1 layer had no chance of being accessed until after (3).
So, if enough time passes between (1) and (3), then (4) will observe a layer with now-last_activity > threshold and evict it

The fix is to require the first record_residence_event to happen while we already hold the layer map lock.
The API requires a ref to a BatchedUpdates as a witness that we are inside a layer map lock.
That is not fool-proof, e.g., new call sites for insert_historic could just completely forget to record the residence event.
It would be nice to prevent this at the type level.
In the meantime, we have a rate-limited log messages to warn us, if such an implementation error sneaks in in the future.

fixes #3593
fixes #3942

github-actions · 2023-04-11T18:33:41Z

Test results for `9b41b5f`:

debug build: 225 tests run: 215 passed, 0 failed, 10 skipped (full report)

release build: 225 tests run: 215 passed, 0 failed, 10 skipped (full report)

problame

Should I duplicate the explainer of the race condition somewhere in the code, as a comment? If so, where?

koivunej · 2023-04-12T13:17:54Z

WARN... unexpectedly downloading

I think we saw this in logs but probably forgot to add a note. But good that you re-hit that.

koivunej · 2023-04-12T13:19:18Z

So, we have to do it at the call sites of insert_historic.

Makes me think the #3775 fix or wrapping is more needed than not.

test_runner/regress/test_threshold_based_eviction.py

pageserver/src/tenant/timeline.rs

koivunej

Mostly trusting the PR desc, code matching it and the test passing, looking good. Comments mostly questions.

problame · 2023-04-13T10:02:12Z

Makes me think the #3775 fix or wrapping is more needed than not.

Yeah, had that thought as well.

…the end

…ote_layer" This reverts commit 3f96e00ed027487f35798dce50b15ded3e6a1baf.

problame · 2023-04-13T14:53:04Z

Changes:

Implemented an alternative approach that puts more responsibility to the layer-creating code. Pushes some checks into type system by requiring a witness. See commit feat: alternative approach that takes a witness for layer map lock held.
Rebased (insert_historic can now fail, had conflicts, CI wouldn't run anymore on this branch)

@koivunej WDYT, is the new approach better?

…ess for layer map lock held"

koivunej

Still on the approval stance. I don't see a huge difference, but the witness certainly does guide towards the wanted implementation. At the same time it cannot guide towards not-leaving the recording out, which doesn't really fit in our current types. Would require some two-step builder.

But it's not like we are trying to make a fool-proof library out of this, and the only downside is disk based eviction giving out a warning.

pageserver/src/tenant/storage_layer.rs

test_runner/regress/test_threshold_based_eviction.py

test_runner/regress/test_metric_collection.py

pageserver/src/tenant/timeline.rs

…unction

problame · 2023-04-14T12:07:55Z

@koivunej in reaction to your comment on the log message, I pushed
feat: rate-limit logging + centralize in the latest_activity method f , I think this is the max amount of yak-shaving I'm able to tolerate ;)

Co-authored-by: Joonas Koivunen <joonas@neon.tech>

koivunej

I need to dismiss my earlier review. Either I may have confused some two PRs or I don't really follow the latest changes. I don't have time to look at this this evening, will need to continue later.

pageserver/src/tenant/storage_layer.rs

pageserver/src/tenant/timeline.rs

test_runner/regress/test_metric_collection.py

stale

pageserver/src/tenant/timeline.rs

pageserver/src/tenant/storage_layer.rs

koivunej

I preferred the non-last minute version; having to require the ratelimited logging is a problem in itself caused by the fact how we currently don't always have a last access timestamp for what I understand, api design reasons. It wasn't a problem in the past so I already forgot why is it a problem now.

I preferred the pre-ratelimited version at f480844^ which I already approved; the logging could be done at the callsites (for disk usage based eviction) and maybe for eviction task we could handle it in some summary if at all.

Looking at this it will take a lot longer to understand what is the case where it remains None, I think I proposed SystemTime::now for that which I can now find from the other.

problame · 2023-04-25T14:03:46Z

I preferred the non-last minute version; having to require the ratelimited logging is a problem in itself caused by the fact how we currently don't always have a last access timestamp for what I understand, api design reasons. It wasn't a problem in the past so I already forgot why is it a problem now.

We never expect to hit the log message because we're careful to add the record_residence_event calls in all the right places.
However, if we forget that in a branch not covered by tests (e.g., in a future refactoring), then the risk is that we're hitting it for many layers, thereby flooding the ERROR log.

the logging could be done at the callsites (for disk usage based eviction) and maybe for eviction task we could handle it in some summary if at all.

For disk-usage-based eviction, rate-limiting to once per iteration is fine.

For the per-timeline eviction task, rate-limiting to once per ieration still leaves $num_timelines/$period ERROR logs per pageserver. E.g., 2000msg/10min = 3msg/sec`.

IMO that's too much, hence the global rate limit.
It's an implementation issue after all.
It affects all call sites similarly.
Hence IMO it's nonsense to log at the callsites, esp. if one of them (per-timeline eviction task) will require rate limiting.

The ugliness of the rate limiting is constrainted to the impl, where we have a "nice" comment explaining the situation.

Looking at this it will take a lot longer to understand what is the case where it remains None, I think I proposed SystemTime::now for that which I can now find from the other.

The warn message will still print every 10 seconds. It really takes no genius to grep for the message in the codebase, then do git blame / read surrounding code, which is well-commented. So, I think it's easy to understand what's going on.

Does the above convince you? If not, please state what to do with the per-timeline eviction task logging. I'll implement that on top of f480844^ then.

libs/utils/src/rate_limit_closure.rs

pageserver/src/tenant/storage_layer.rs

koivunej

I still dislike the approach (RateLimitClosure or after rename), static mutexes, but perhaps it truly is unavoidable or at least I don't have the energy to come up with alternative. At least the current review comments need to be addressed.

…lers

Following Joonas's earlier suggestion in #4005 (comment)

…iction-policy-unit-tests

problame · 2023-05-04T14:17:15Z

Updated the PR description to the final commit message.

problame requested a review from koivunej April 11, 2023 18:41

problame marked this pull request as ready for review April 11, 2023 18:41

problame requested review from a team as code owners April 11, 2023 18:41

problame requested review from lubennikovaav and removed request for a team April 11, 2023 18:41

problame commented Apr 11, 2023

View reviewed changes

problame removed the request for review from lubennikovaav April 11, 2023 18:42

koivunej reviewed Apr 12, 2023

View reviewed changes

test_runner/regress/test_threshold_based_eviction.py Show resolved Hide resolved

koivunej reviewed Apr 12, 2023

View reviewed changes

test_runner/regress/test_threshold_based_eviction.py Show resolved Hide resolved

koivunej reviewed Apr 12, 2023

View reviewed changes

pageserver/src/tenant/timeline.rs Outdated Show resolved Hide resolved

koivunej approved these changes Apr 12, 2023

View reviewed changes

problame added 5 commits April 13, 2023 16:49

eviction: regression test + distinguish layer write from map insert

d53c33c

refactor: simplify MapInfoProjection type & more preceise asserts at …

ed29e17

…the end

feat: technically the same applies for Timeline::download_remote_layer

409b0f3

Revert "feat: technically the same applies for Timeline::download_rem…

30a77e0

…ote_layer" This reverts commit 3f96e00ed027487f35798dce50b15ded3e6a1baf.

feat: alternative approach that takes a witness for layer map lock held

767c57f

problame force-pushed the problame/threshold-eviction-policy-unit-tests branch from 72fad66 to 767c57f Compare April 13, 2023 14:51

problame added 2 commits April 14, 2023 10:09

fixup rebase: eviction: env.postgres was renamed to env.endpoints

a55987a

fix doc string in "feat: feat: alternative approach that takes a witn…

c2f5a4d

…ess for layer map lock held"

koivunej previously approved these changes Apr 14, 2023

View reviewed changes

koivunej reviewed Apr 14, 2023

View reviewed changes

pageserver/src/tenant/timeline.rs Outdated Show resolved Hide resolved

feat: rate-limit logging + centralize in the latest_activity method f…

f480844

…unction

fix: use Mutex::default()

63e5993

Co-authored-by: Joonas Koivunen <joonas@neon.tech>

feat: forgot to commit rate_limit_closure module

8de967c

koivunej reviewed Apr 14, 2023

View reviewed changes

pageserver/src/tenant/storage_layer.rs Outdated Show resolved Hide resolved

pageserver/src/tenant/timeline.rs Outdated Show resolved Hide resolved

test_runner/regress/test_metric_collection.py Show resolved Hide resolved

koivunej reviewed Apr 25, 2023

View reviewed changes

pageserver/src/tenant/timeline.rs Outdated Show resolved Hide resolved

koivunej reviewed Apr 25, 2023

View reviewed changes

pageserver/src/tenant/storage_layer.rs Outdated Show resolved Hide resolved

koivunej requested changes Apr 25, 2023

View reviewed changes

koivunej reviewed May 3, 2023

View reviewed changes

libs/utils/src/rate_limit_closure.rs Outdated Show resolved Hide resolved

koivunej mentioned this pull request May 3, 2023

Layer should implement Display and we should use it #4145

Closed

koivunej reviewed May 3, 2023

View reviewed changes

libs/utils/src/rate_limit_closure.rs Outdated Show resolved Hide resolved

koivunej reviewed May 3, 2023

View reviewed changes

pageserver/src/tenant/storage_layer.rs Outdated Show resolved Hide resolved

koivunej requested changes May 3, 2023

View reviewed changes

problame added 7 commits May 4, 2023 09:27

apply Joonas's suggestion

40ef242

rename rate_limit_closure => rate_limit / RateLimitClosure=>RateLimit

da19e64

better way than tokio::spawn for logging at global scope

0233cca

latest_activity(): return Option and use unwrap_or{,_else} in the cal…

fedaa65

…lers

use SystemTime::now() instead of SystemTime::UNIX_EPOCH as fallback

b711449

Following Joonas's earlier suggestion in #4005 (comment)

Merge remote-tracking branch 'origin/main' into problame/threshold-ev…

3f5de7c

…iction-policy-unit-tests

fix merge fallout

9b41b5f

koivunej approved these changes May 4, 2023

View reviewed changes

problame merged commit 7dd9553 into main May 4, 2023

problame deleted the problame/threshold-eviction-policy-unit-tests branch May 4, 2023 14:16

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

eviction: regression test + distinguish layer write from map insert #4005

eviction: regression test + distinguish layer write from map insert #4005

problame commented Apr 11, 2023 •

edited

Loading

github-actions bot commented Apr 11, 2023 •

edited

Loading

problame left a comment

koivunej commented Apr 12, 2023

koivunej commented Apr 12, 2023

koivunej left a comment

problame commented Apr 13, 2023

problame commented Apr 13, 2023

koivunej left a comment

problame commented Apr 14, 2023

koivunej left a comment

koivunej left a comment

problame commented Apr 25, 2023

koivunej left a comment •

edited

Loading

problame commented May 4, 2023

eviction: regression test + distinguish layer write from map insert #4005

eviction: regression test + distinguish layer write from map insert #4005

Conversation

problame commented Apr 11, 2023 • edited Loading

github-actions bot commented Apr 11, 2023 • edited Loading

Test results for 9b41b5f:

debug build: 225 tests run: 215 passed, 0 failed, 10 skipped (full report)

release build: 225 tests run: 215 passed, 0 failed, 10 skipped (full report)

problame left a comment

Choose a reason for hiding this comment

koivunej commented Apr 12, 2023

koivunej commented Apr 12, 2023

koivunej left a comment

Choose a reason for hiding this comment

problame commented Apr 13, 2023

problame commented Apr 13, 2023

koivunej left a comment

Choose a reason for hiding this comment

problame commented Apr 14, 2023

koivunej left a comment

Choose a reason for hiding this comment

koivunej left a comment

Choose a reason for hiding this comment

problame commented Apr 25, 2023

koivunej left a comment • edited Loading

Choose a reason for hiding this comment

problame commented May 4, 2023

problame commented Apr 11, 2023 •

edited

Loading

github-actions bot commented Apr 11, 2023 •

edited

Loading

Test results for `9b41b5f`:

koivunej left a comment •

edited

Loading